[Sbcl-help] defmethod inefficiency
Todd Sabin
Hi,
I recently noticed that defmethod seems to have a serious inefficiency
in it somewhere. Adding new methods to a generic function takes
longer and longer. I've attached a demostration file, which is
basically just 500 defmethods on the same g.f. If you compile that file
and then load it, you'll see:
(This was 0.9.12 on an AMD64 box. I tried 0.9.16, but it was pretty much
the same.)
[tas@tron ~]{4} sbcl --userinit /dev/null
This is SBCL 0.9.12, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.
SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* (compile-file "defmethod-test")
; compiling file "/home/tas/defmethod-test.lisp" (written 07 SEP 2006 01:36:06 PM):
; compiling (DEFPACKAGE #:DEFMETHOD-TEST ...)
; compiling (IN-PACKAGE #:DEFMETHOD-TEST)
; compiling (DEFGENERIC MY-METHOD ...)
; compiling (DEFMETHOD MY-METHOD ...)
; compiling (DEFMETHOD MY-METHOD ...)
[snipped]
; compiling (DEFMETHOD MY-METHOD ...)
; compiling (DEFMETHOD MY-METHOD ...)
; compiling (DEFMETHOD MY-METHOD ...)
; /home/tas/defmethod-test.fasl written
; compilation finished in 0:00:32
#P"/home/tas/defmethod-test.fasl"
NIL
NIL
* (time (load *))
Evaluation took:
43.433 seconds of real time
38.87509 seconds of user run time
0.948855 seconds of system run time
0 page faults and
2,916,601,264 bytes consed.
T
* (time (load **))
Evaluation took:
228.139 seconds of real time
190.0551 seconds of user run time
5.312193 seconds of system run time
0 page faults and
13,741,608,400 bytes consed.
T
*
As you can see, loading look around 40 seconds the first time, and
then even longer the second time, presumably because all 500 methods
already exist the second time around.
Cmucl only takes 1s the first load, and 2s the second load:
[tas@tron ~]{396} lisp -noinit
CMU Common Lisp Snapshot 2005-01, running on tron.qnz.org
With core: /usr/local/lib/cmucl/lib/lisp.core
Dumped on: Tue, 2005-01-04 22:50:46-05:00 on lorien
See <http://www.cons.org/cmucl/> for support information.
Loaded subsystems:
Python 1.1, target Intel x86
CLOS based on Gerd's PCL 2004/04/14 03:32:47
* (compile-file "/home/tas/defmethod-test")
; Python version 1.1, VM version Intel x86 on 11 SEP 06 10:48:41 am.
; Compiling: /home/tas/defmethod-test.lisp 07 SEP 06 01:36:06 pm
; Compiling DEFMETHOD MY-METHOD ((EQL #)):
[snipped]
; Compiling DEFMETHOD MY-METHOD ((EQL #)):
; Byte Compiling Top-Level Form:
; /home/tas/defmethod-test.x86f written.
; Compilation finished in 0:00:20.
#P"/home/tas/defmethod-test.x86f"
NIL
NIL
* (time (load *))
; Compiling LAMBDA NIL:
; Compiling Top-Level Form:
; Loading #P"/home/tas/defmethod-test.x86f".
; [GC threshold exceeded with 21,056,080 bytes in use. Commencing GC.]
; [GC completed with 10,142,496 bytes retained and 10,913,584 bytes freed.]
; [GC will next occur when at least 22,142,496 bytes are in use.]
; [GC threshold exceeded with 22,157,936 bytes in use. Commencing GC.]
; [GC completed with 10,557,952 bytes retained and 11,599,984 bytes freed.]
; [GC will next occur when at least 22,557,952 bytes are in use.]
; Evaluation took:
; 1.07 seconds of real time
; 0.969852 seconds of user run time
; 0.034995 seconds of system run time
; 2,143,969,572 CPU cycles
; [Run times include 0.08 seconds GC run time]
; 0 page faults and
; 21,321,384 bytes consed.
;
T
* (time (load **))
; Compiling LAMBDA NIL:
; Compiling Top-Level Form:
; Loading #P"/home/tas/defmethod-test.x86f".
; [GC threshold exceeded with 22,567,392 bytes in use. Commencing GC.]
; [GC completed with 11,128,440 bytes retained and 11,438,952 bytes freed.]
; [GC will next occur when at least 23,128,440 bytes are in use.]
; [GC threshold exceeded with 23,143,976 bytes in use. Commencing GC.]
; [GC completed with 7,458,672 bytes retained and 15,685,304 bytes freed.]
; [GC will next occur when at least 19,458,672 bytes are in use.]
; Evaluation took:
; 2.08 seconds of real time
; 1.939705 seconds of user run time
; 0.037994 seconds of system run time
; 4,169,211,120 CPU cycles
; [Run times include 0.12 seconds GC run time]
; 0 page faults and
; 20,394,008 bytes consed.
;
T
*
Any ideas why sbcl is so much slower than cmucl here, or if there's
something that can be done to speed it up?
Thanks,
Todd
Juho Snellman
> I recently noticed that defmethod seems to have a serious inefficiency
> in it somewhere. Adding new methods to a generic function takes
> longer and longer.
Doing (setf sb-pcl::*max-emf-precomputation-methods* 100) will
probably give you times reasonably close to the CMUCL ones.
--
Juho Snellman
-------------------------------------------------------------------------
Using Tomcat but need to do more? Need to support web services, security?
Get stuff done quickly with pre-integrated technology to make your job easier
Download IBM WebSphere Application Server v.1.0.1 based on Apache Geronimo
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=120709&bid=263057&dat=121642
_______________________________________________
Sbcl-help mailing list
Sbcl...@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/sbcl-help
Gary King
Todd Sabin
> Todd Sabin <tsa...@optonline.net> writes:
>> I recently noticed that defmethod seems to have a serious inefficiency
>> in it somewhere. Adding new methods to a generic function takes
>> longer and longer.
>
> Doing (setf sb-pcl::*max-emf-precomputation-methods* 100) will
> probably give you times reasonably close to the CMUCL ones.
Yes, it does. Thanks.
I read the doc on that variable (from cmucl), and think I get it. In
my example, there are 500 defmethods on a generic function. By
default, each one of those is going to precompute the effective
methods. 499 of those precomputations are just being thrown away at
the next defmethod. With the variable set, the precomputations aren't
performed. The first call to the generic function will need to do
that computation, but only once.
Is that basically right?
--
Todd Sabin <tsa...@optonline.net>
Juho Snellman
> Juho Snellman <jsn...@iki.fi> writes:
> > Todd Sabin <tsa...@optonline.net> writes:
> >> I recently noticed that defmethod seems to have a serious inefficiency
> >> in it somewhere. Adding new methods to a generic function takes
> >> longer and longer.
> >
> > Doing (setf sb-pcl::*max-emf-precomputation-methods* 100) will
> > probably give you times reasonably close to the CMUCL ones.
>
> Yes, it does. Thanks.
>
> I read the doc on that variable (from cmucl), and think I get it. In
> my example, there are 500 defmethods on a generic function. By
> default, each one of those is going to precompute the effective
> methods. 499 of those precomputations are just being thrown away at
> the next defmethod. With the variable set, the precomputations aren't
> performed. The first call to the generic function will need to do
> that computation, but only once.
>
> Is that basically right?
I think that's basically correct.
The right default value for that variable is an interesting
question. It was changed from 10 to NIL in SBCL a couple of years ago
on the theory that there's no non-arbitrary numeric value for it =>
the only natural value is NIL. Did this come up in a real-world
application? I would've expected gfs with hundreds of methods to be
rather rare.
Also note that some expensive computations done whenever a method is
added to/removed from a gf will not be affected by this variable, even
if the results are going to be immediately thrown away, due to their
exact timing being specified by AMOP. So some inefficiency in
DEFMETHOD is unavoidable.
--
Juho Snellman
Todd Sabin
> Todd Sabin <tsa...@optonline.net> writes:
>> Juho Snellman <jsn...@iki.fi> writes:
>> > Todd Sabin <tsa...@optonline.net> writes:
>> >> I recently noticed that defmethod seems to have a serious inefficiency
>> >> in it somewhere. Adding new methods to a generic function takes
>> >> longer and longer.
>> >
>> > Doing (setf sb-pcl::*max-emf-precomputation-methods* 100) will
>> > probably give you times reasonably close to the CMUCL ones.
>>
>> Yes, it does. Thanks.
>> [...]
> The right default value for that variable is an interesting
> question. It was changed from 10 to NIL in SBCL a couple of years ago
> on the theory that there's no non-arbitrary numeric value for it =>
> the only natural value is NIL. Did this come up in a real-world
> application? I would've expected gfs with hundreds of methods to be
> rather rare.
Yes, this came up in a real-world app. It's something similar to
ethereal, so there are definitions for different types of network
data. Each type usually has its own parser, which is a method on a
gf. I started generating code from RPC idl definitions, and a single
idl might define 100 types, or more. And there are a lot of RPC
interfaces.
Of course that doesn't mean this isn't rare, not really sure. Cmucl's
default of 100 seems to make a fair amount of sense, though. I'm
obviously biased, but it seems like if you're creating more than 100
methods on a gf, odds are that you're going to be creating them in
large bunches. So limiting the worst case sounds like a good idea.
> Also note that some expensive computations done whenever a method is
> added to/removed from a gf will not be affected by this variable, even
> if the results are going to be immediately thrown away, due to their
> exact timing being specified by AMOP. So some inefficiency in
> DEFMETHOD is unavoidable.
Okay, thanks.
--
Todd Sabin <tsa...@optonline.net>
Christophe Rhodes
> The right default value for that variable is an interesting
> question. It was changed from 10 to NIL in SBCL a couple of years ago
> on the theory that there's no non-arbitrary numeric value for it =>
> the only natural value is NIL. Did this come up in a real-world
> application? I would've expected gfs with hundreds of methods to be
> rather rare.
There's a case in BUGS about this variable too: look at bug #281. I
can't remember if it is still applicable, but I think setting it to a
non-NIL value is likely to render the system vulnerable to a carefully
crafted test along the lines of that report.
Cheers,
Christophe